Add a small profiling framework

This should help aid in debugging slow parts of cargo by setting the
CARGO_PROFILE environment variable.

diff --git a/src/cargo/core/registry.rs b/src/cargo/core/registry.rs
index d737d429f52a7582d7c1a9696fcc48189caa685f..789bf149013d4bedac1b449847ed728b1954dbff 100644 (file)
--- a/src/cargo/core/registry.rs
+++ b/src/cargo/core/registry.rs
@@ -1,5 +1,5 @@
 use core::{Source, SourceId, SourceMap, Summary, Dependency, PackageId, Package};
-use util::{CargoResult, ChainError, Config, human};
+use util::{CargoResult, ChainError, Config, human, profile};
 
 pub trait Registry {
     fn query(&mut self, name: &Dependency) -> CargoResult<Vec<Summary>>;
@@ -83,7 +83,9 @@ impl<'a> PackageRegistry<'a> {
             let mut source = source_id.load(self.config);
 
             // Ensure the source has fetched all necessary remote data.
+            let p = profile::start(format!("updating: {}", source_id));
             try!(source.update());
+            drop(p);
 
             if override {
                 self.overrides.push(source_id.clone());

diff --git a/src/cargo/core/source.rs b/src/cargo/core/source.rs
index 9091a0ef9578367f03fe16b25a41783ddac898ab..c186a628f19d43f8b74bd3e462b24ea905c81827 100644 (file)
--- a/src/cargo/core/source.rs
+++ b/src/cargo/core/source.rs
@@ -158,8 +158,11 @@ impl Show for SourceId {
                     try!(write!(f, "?ref={}", reference));
                 }
 
-                if precise.is_some() {
-                    try!(write!(f, "#{}", precise.get_ref()));
+                match *precise {
+                    Some(ref s) => {
+                        try!(write!(f, "#{}", s.as_slice().slice_to(8)));
+                    }
+                    None => {}
                 }
             },
             SourceId { kind: RegistryKind, .. } => {

diff --git a/src/cargo/lib.rs b/src/cargo/lib.rs
index ae8aeb22bf2ccbaa0168c2d26b3f8f5de260781c..f80f38d2e83e0444ebc6cf151e1c71603cdc63e0 100644 (file)
--- a/src/cargo/lib.rs
+++ b/src/cargo/lib.rs
@@ -11,6 +11,7 @@ extern crate regex;
 extern crate semver;
 extern crate serialize;
 extern crate term;
+extern crate time;
 extern crate url;
 #[phase(plugin)] extern crate regex_macros;
 #[phase(plugin, link)] extern crate log;

diff --git a/src/cargo/ops/cargo_compile.rs b/src/cargo/ops/cargo_compile.rs
index 96182344b8cab3db6b2c8c5f4a0832c6a4dd3909..43a0214ffa8c89f5e308201847533632c5c43ce3 100644 (file)
--- a/src/cargo/ops/cargo_compile.rs
+++ b/src/cargo/ops/cargo_compile.rs
@@ -34,6 +34,7 @@ use ops;
 use sources::{PathSource};
 use util::config::{Config, ConfigValue};
 use util::{CargoResult, Wrap, config, internal, human, ChainError, toml};
+use util::profile;
 
 pub struct CompileOptions<'a> {
     pub update: bool,
@@ -67,6 +68,7 @@ pub fn compile(manifest_path: &Path,
                                                    manifest_path.dir_path()));
 
     let (packages, resolve, resolve_with_overrides, sources) = {
+        let _p = profile::start("resolving...");
         let lockfile = manifest_path.dir_path().join("Cargo.lock");
         let source_id = package.get_package_id().get_source_id();
 
@@ -117,6 +119,7 @@ pub fn compile(manifest_path: &Path,
     }).collect::<Vec<&Target>>();
 
     {
+        let _p = profile::start("compiling");
         let mut config = try!(Config::new(*shell, update, jobs, target));
         try!(scrape_target_config(&mut config, &user_configs));
 

diff --git a/src/cargo/ops/cargo_rustc/context.rs b/src/cargo/ops/cargo_rustc/context.rs
index ad078865b21cc84560b7a2795a39ca9002e089d0..6e65574ac07c804a45142506e793828d1701b0aa 100644 (file)
--- a/src/cargo/ops/cargo_rustc/context.rs
+++ b/src/cargo/ops/cargo_rustc/context.rs
@@ -3,7 +3,7 @@ use std::str;
 
 use core::{SourceMap, Package, PackageId, PackageSet, Resolve, Target};
 use util;
-use util::{CargoResult, ChainError, internal, Config};
+use util::{CargoResult, ChainError, internal, Config, profile};
 
 use super::layout::{Layout, LayoutProxy};
 
@@ -100,6 +100,8 @@ impl<'a, 'b> Context<'a, 'b> {
     /// Prepare this context, ensuring that all filesystem directories are in
     /// place.
     pub fn prepare(&mut self, pkg: &'a Package) -> CargoResult<()> {
+        let _p = profile::start("preparing layout");
+
         try!(self.host.prepare().chain_error(|| {
             internal(format!("couldn't prepare build directories for `{}`",
                              pkg.get_name()))

diff --git a/src/cargo/ops/cargo_rustc/fingerprint.rs b/src/cargo/ops/cargo_rustc/fingerprint.rs
index 3db58b3e1d4b1d57cbcfa7ad47b13eb1048a5ae5..3b4fd04dd8d1bae8bdd6598e48365acd6de91d42 100644 (file)
--- a/src/cargo/ops/cargo_rustc/fingerprint.rs
+++ b/src/cargo/ops/cargo_rustc/fingerprint.rs
@@ -5,7 +5,7 @@ use std::io::{fs, File};
 use core::{Package, Target};
 use util;
 use util::hex::short_hash;
-use util::{CargoResult, Fresh, Dirty, Freshness, internal, Require};
+use util::{CargoResult, Fresh, Dirty, Freshness, internal, Require, profile};
 
 use super::job::Job;
 use super::context::Context;
@@ -24,6 +24,7 @@ use super::context::Context;
 pub fn prepare<'a, 'b>(cx: &mut Context<'a, 'b>, pkg: &'a Package,
                        targets: &[&'a Target])
                        -> CargoResult<(Freshness, Job, Job)> {
+    let _p = profile::start(format!("fingerprint: {}", pkg));
     let filename = format!(".{}.{}.fingerprint", pkg.get_name(),
                            short_hash(pkg.get_package_id()));
     let filename = filename.as_slice();

diff --git a/src/cargo/ops/cargo_rustc/job_queue.rs b/src/cargo/ops/cargo_rustc/job_queue.rs
index a52a23913cb5c0decec8fd37ab55e09a98e5e6ec..4eb5a516e03e3fa88b452318937b87f43705667d 100644 (file)
--- a/src/cargo/ops/cargo_rustc/job_queue.rs
+++ b/src/cargo/ops/cargo_rustc/job_queue.rs
@@ -4,7 +4,7 @@ use term::color::YELLOW;
 
 use core::{Package, PackageId, Resolve};
 use util::{Config, TaskPool, DependencyQueue, Fresh, Dirty, Freshness};
-use util::CargoResult;
+use util::{CargoResult, profile};
 
 use super::job::Job;
 
@@ -51,6 +51,8 @@ impl<'a, 'b> JobQueue<'a, 'b> {
     /// necessary dependencies, in order. Freshness is propagated as far as
     /// possible along each dependency chain.
     pub fn execute(&mut self) -> CargoResult<()> {
+        let _p = profile::start("executing the job graph");
+
         // Iteratively execute the dependency graph. Each turn of this loop will
         // schedule as much work as possible and then wait for one job to finish,
         // possibly scheduling more work afterwards.

diff --git a/src/cargo/ops/cargo_rustc/mod.rs b/src/cargo/ops/cargo_rustc/mod.rs
index 1b94648d8cca980697c13c8f05c867f9d3d7d42b..1f5d689097426f77eb02192b327ca18aeb955493 100644 (file)
--- a/src/cargo/ops/cargo_rustc/mod.rs
+++ b/src/cargo/ops/cargo_rustc/mod.rs
@@ -7,7 +7,7 @@ use semver::Version;
 use core::{SourceMap, Package, PackageId, PackageSet, Target, Resolve};
 use util;
 use util::{CargoResult, ProcessBuilder, CargoError, human, caused_human};
-use util::{Config, Freshness, internal, ChainError};
+use util::{Config, Freshness, internal, ChainError, profile};
 
 use self::job::Job;
 use self::job_queue::JobQueue;
@@ -87,6 +87,7 @@ fn compile<'a, 'b>(targets: &[&'a Target], pkg: &'a Package,
                    jobs: &mut Vec<(&'a Package, Freshness, (Job, Job))>)
                    -> CargoResult<()> {
     debug!("compile_pkg; pkg={}; targets={}", pkg, targets);
+    let _p = profile::start(format!("preparing: {}", pkg));
 
     if targets.is_empty() {
         return Ok(())

diff --git a/src/cargo/util/mod.rs b/src/cargo/util/mod.rs
index 7d567e68e87863f0ccd6c5266e74ac48c0b24649..f1da499f42fb4f377c194fc2bbbd3bd130d1fad9 100644 (file)
--- a/src/cargo/util/mod.rs
+++ b/src/cargo/util/mod.rs
@@ -20,6 +20,7 @@ pub mod toml;
 pub mod paths;
 pub mod errors;
 pub mod hex;
+pub mod profile;
 mod pool;
 mod dependency_queue;
 mod to_url;

diff --git a/src/cargo/util/profile.rs b/src/cargo/util/profile.rs
new file mode 100644 (file)
index 0000000..11e43e1
--- /dev/null
+++ b/src/cargo/util/profile.rs
@@ -0,0 +1,62 @@
+use std::os;
+use std::mem;
+use std::fmt::Show;
+use time;
+
+local_data_key!(profile_stack: Vec<u64>)
+local_data_key!(messages: Vec<Message>)
+
+type Message = (uint, u64, String);
+
+pub struct Profiler {
+    desc: String,
+}
+
+fn enabled() -> bool { os::getenv("CARGO_PROFILE").is_some() }
+
+pub fn start<T: Show>(desc: T) -> Profiler {
+    if !enabled() { return Profiler { desc: String::new() } }
+
+    let mut stack = profile_stack.replace(None).unwrap_or(Vec::new());
+    stack.push(time::precise_time_ns());
+    profile_stack.replace(Some(stack));
+
+    Profiler {
+        desc: desc.to_string(),
+    }
+}
+
+impl Drop for Profiler {
+    fn drop(&mut self) {
+        if !enabled() { return }
+
+        let mut stack = profile_stack.replace(None).unwrap_or(Vec::new());
+        let mut msgs = messages.replace(None).unwrap_or(Vec::new());
+
+        let start = stack.pop().unwrap();
+        let end = time::precise_time_ns();
+
+        let msg = mem::replace(&mut self.desc, String::new());
+        if stack.len() == 0 {
+            fn print(lvl: uint, msgs: &[Message]) {
+                let mut last = 0;
+                for (i, &(l, time, ref msg)) in msgs.iter().enumerate() {
+                    if l != lvl { continue }
+                    println!("{} {:6}ms - {}", "    ".repeat(lvl + 1),
+                             time / 1000000, msg);
+
+                    print(lvl + 1, msgs.slice(last, i));
+                    last = i;
+                }
+
+            }
+            msgs.push((0, end - start, msg));
+            print(0, msgs.as_slice());
+        } else {
+            msgs.push((stack.len(), end - start, msg));
+        }
+        profile_stack.replace(Some(stack));
+        messages.replace(Some(msgs));
+
+    }
+}